Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tracing: Add spanID field to access logs and http.vars.span_id placeholder #6646

Merged
merged 2 commits into from
Oct 21, 2024
Merged

tracing: Add spanID field to access logs and http.vars.span_id placeholder #6646

merged 2 commits into from
Oct 21, 2024

Conversation

YifanYang6
Copy link
Contributor

@YifanYang6 YifanYang6 commented Oct 19, 2024 •
edited
Loading

In PR #5507, the traceid was added to the logs. To further align with the OpenTelemetry Log Correlation specification and achieve complete log correlation using trace context, we have now included the spanid alongside the traceid.

Benchmark Comparison

I conducted benchmarks to assess the performance impact of adding the spanid. Since traceid and spanid are always used together, I modified the existing benchmarks for traceid to include spanid. Below is the performance comparison before and after adding the spanid:

Before: 

$ go test -benchtime=3s -count=10 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee before.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor               
BenchmarkServer_LogRequest-64                    3140806              1174 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3026678              1161 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3103068              1156 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3121268              1152 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3098882              1163 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3171706              1147 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3098536              1128 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3198552              1143 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3118201              1159 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3211209              1151 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27751924               127.9 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28101333               125.2 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28519773               124.9 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27652406               126.6 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28332801               124.6 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28507286               125.0 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28651822               126.3 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28575466               130.1 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28702560               128.1 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28392454               125.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2870023              1248 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2934045              1239 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2897414              1240 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2886142              1240 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2973252              1241 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2958910              1214 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2922925              1219 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2962358              1230 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2883412              1225 ns/op             484 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          3014709              1151 ns/op             484 B/op          4 allocs/op
PASS
ok      github.com/caddyserver/caddy/v2/modules/caddyhttp       133.403s
After: 

$ go test -benchtime=3s -count=10 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee after.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor               
BenchmarkServer_LogRequest-64                    3152115              1158 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3094155              1143 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3174631              1132 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3161185              1133 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3190516              1136 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3090571              1154 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3119666              1153 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3145326              1144 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3134314              1135 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest-64                    3138734              1136 ns/op             419 B/op          4 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28379570               133.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28388329               134.3 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28012402               124.0 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28187100               126.3 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28356514               125.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         26432298               125.4 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27307333               124.9 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         27985292               133.6 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28657483               132.7 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64         28491796               124.5 ns/op             8 B/op          1 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2783799              1273 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2767974              1324 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2786803              1295 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2805546              1269 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2816472              1287 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2801752              1299 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2732166              1316 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2740275              1316 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2766216              1293 ns/op             548 B/op          4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64          2706841              1348 ns/op             548 B/op          4 allocs/op
PASS
ok      github.com/caddyserver/caddy/v2/modules/caddyhttp       134.236s

Diff:

$ benchstat before.txt after.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor               
                               │ before.txt  │             after.txt              │
                               │   sec/op    │   sec/op     vs base               │
Server_LogRequest-64             1.154µ ± 1%   1.140µ ± 1%       ~ (p=0.055 n=10)
Server_LogRequest_NopLogger-64   125.9n ± 2%   125.9n ± 6%       ~ (p=0.698 n=10)
Server_LogRequest_WithTrace-64   1.235µ ± 2%   1.297µ ± 2%  +5.06% (p=0.000 n=10)
geomean                          564.0n        570.9n       +1.23%

                               │ before.txt │              after.txt               │
                               │    B/op    │    B/op     vs base                  │
Server_LogRequest-64             419.0 ± 0%   419.0 ± 0%        ~ (p=1.000 n=10) ¹
Server_LogRequest_NopLogger-64   8.000 ± 0%   8.000 ± 0%        ~ (p=1.000 n=10) ¹
Server_LogRequest_WithTrace-64   484.0 ± 0%   548.0 ± 0%  +13.22% (p=0.000 n=10)
geomean                          117.5        122.5        +4.23%
¹ all samples are equal

                               │ before.txt │              after.txt              │
                               │ allocs/op  │ allocs/op   vs base                 │
Server_LogRequest-64             4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
Server_LogRequest_NopLogger-64   1.000 ± 0%   1.000 ± 0%       ~ (p=1.000 n=10) ¹
Server_LogRequest_WithTrace-64   4.000 ± 0%   4.000 ± 0%       ~ (p=1.000 n=10) ¹
geomean                          2.520        2.520       +0.00%
¹ all samples are equal

The addition of spanid to the logs led to a slight increase (~5%) in processing time. Memory usage increased in ~13%, as expected.

I also added the http.vars.span_id placeholder, similar to what was done in PR #6308 for the http.vars.trace_id placeholder.

@YifanYang6
logging: Add spanID field to access logs when tracing is enabled
926e369 
Signed-off-by: YifanYang6 <yifanyang6@link.cuhk.edu.cn>
@YifanYang6
tracing: add http.vars.span_id placeholder when tracing is enabled
9ff9682 
Signed-off-by: YifanYang6 <yifanyang6@link.cuhk.edu.cn>
@YifanYang6
Copy link
Contributor Author

If needed, I can also update the related documentation for these changes in the Caddy website.

@mholt
Copy link
Member

mholt commented Oct 19, 2024

Thanks for the PR!

Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?

@YifanYang6
Copy link
Contributor Author

YifanYang6 commented Oct 19, 2024 •
edited
Loading

Thanks for the PR!

Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?

That's correct. The performance impact occurs only when tracing is enabled, as both traceid and spanid are added to the logs only in that scenario.

However, it seemed that my previous benchmarks showed some impact even when tracing wasn't enabled. I reran the benchmarks several times, and the new results confirm that the performance is affected only when spanid is being added. The slight (~3%) increase in runtime observed earlier was likely just measurement noise.

I've also updated the previous benchmark results.

@francislavoie francislavoie added the feature ⚙️ New feature or request label Oct 20, 2024
@francislavoie francislavoie changed the title Add spanID field to access logs and http.vars.span_id placeholder when tracing is enabled tracing: Add spanID field to access logs and http.vars.span_id placeholder Oct 20, 2024
@hairyhenderson
Copy link
Collaborator

Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?

yes if you mean s/metrics/tracing/ - this is (or, should be) orthogonal to metrics

@mholt mholt merged commit 669fc41 into caddyserver:master Oct 21, 2024
33 checks passed
@mholt mholt added this to the v2.9.0-beta.3 milestone Oct 21, 2024
@YifanYang6 YifanYang6 mentioned this pull request Oct 30, 2024
Merged
francislavoie pushed a commit to caddyserver/website that referenced this pull request Oct 30, 2024
@YifanYang6
docs for PR caddyserver/caddy#6646 (#429)
5e45522 
Signed-off-by: YifanYang6 <yifanyang6@link.cuhk.edu.cn>
YifanYang6 added a commit to CUHK-SE-Group/train-ticket that referenced this pull request Nov 12, 2024
@YifanYang6
ui-dashboard: Update Caddy to v2.9 in Dockerfile and remove temporary…
84a6014 
… binary replacement

- Removed temporary workaround for `spanid` support, as our patch has been merged (caddyserver/caddy#6646).
- Updated to `caddy:2.9` to use the official 2.9 Docker image, which now includes our patch (docker-library/official-images#17848).

Signed-off-by: YifanYang6 <yifanyang6@link.cuhk.edu.cn>
@BrewTestBot BrewTestBot mentioned this pull request Dec 31, 2024
Merged
1 task
francislavoie pushed a commit to caddyserver/website that referenced this pull request Jan 4, 2025
@YifanYang6 @francislavoie
docs for PR caddyserver/caddy#6646 (#429)
f3b6d18 
Signed-off-by: YifanYang6 <yifanyang6@link.cuhk.edu.cn>
@digitaltim-de
Copy link

digitaltim-de commented Jan 12, 2025 •
edited
Loading

No docs for that... I want to use custom tags, any idea how i can send via caddy custom tags to the tracing?

For example i am using this:

    route {
        @traceable {
            not path /build/* /images/* /favicon-32x32.png
        }

        handle @traceable {
            tracing {
                span "[{http.request.method}] {http.request.uri.path}"
               ##here i want add custom tags for sending to the tracing tool jaeger
            }
        }
       
        push
        php_fastcgi php:9000
        encode zstd gzip
        file_server
    }

    ```

    
    I want add tags(); for the tracing any idea how i can do it?

@francislavoie
Copy link
Member

All this does is add the span ID to the logs automatically, when tracing is enabled. That's it. There's not really anything to document.

Tagging is a totally different topic, it's not currently a supported feature.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@hairyhenderson hairyhenderson hairyhenderson approved these changes

Assignees
No one assigned
Labels
feature ⚙️ New feature or request
Projects
None yet
Milestone
v2.9.0-beta.3
Development

Successfully merging this pull request may close these issues.
5 participants
@YifanYang6 @mholt @hairyhenderson @digitaltim-de @francislavoie